Skip to content

Conversation

@MadLittleMods
Copy link
Contributor

@MadLittleMods MadLittleMods commented Sep 12, 2025

Explain how Deferred callbacks interact with logcontexts

Spawning from matrix-org/synapse#12588 (comment)

It turns out Deferred.cancel() is a lot like Deferred.callback()/errback() in that it will trash the logging context:
it can resume a coroutine, which will restore its own logging context, then run:

  • until it blocks, setting the sentinel context
  • or until it terminates, setting the context it was started with

So we need to wrap it in with PreserveLoggingContext():, like we do with .callback():

with PreserveLoggingContext():
    self.render_deferred.cancel()

-- @squahtx, matrix-org/synapse#12588 (comment)

Todo

  • Perhaps some tests to exercise the deferred scenarios would be good. It would be nice to somehow assert broken scenario and fixed

Pull Request Checklist

  • Pull request is based on the develop branch
  • Pull request includes a changelog file. The entry should:
    • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
    • Use markdown where necessary, mostly for code blocks.
    • End with either a period (.) or an exclamation mark (!).
    • Start with a capital letter.
    • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
  • Code style is correct (run the linters)

@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 21:35 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 21:38 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 21:51 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 22:49 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 23:03 Active
await clock.sleep(0)
self._check_test_key("one")

@logcontext_clean
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The rest of the tests in this file are getting @logcontext_clean in #18907

I added @logcontext_clean as it makes sense to fail when we see logcontext_error used in the logcontext tests.

@github-actions github-actions bot deployed to PR Documentation Preview September 12, 2025 23:13 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 13, 2025 01:19 Active
@github-actions github-actions bot deployed to PR Documentation Preview September 13, 2025 16:19 Active
Comment on lines +293 to +318
**Solution 3:** But let's say you *do* want to run (fire-and-forget) the deferred
callback in the current context without running into issues:

We can solve the first issue by using `run_in_background(...)` to run the callback in
the current logcontext and it handles the magic behind the scenes of a) restoring the
calling logcontext before returning to the caller and b) resetting the logcontext to the
sentinel after the deferred completes and we yield control back to the reactor to avoid
leaking the logcontext into the reactor.

To solve the second issue, we can extend the lifetime of the "main" logcontext by
avoiding the `LoggingContext`'s context manager lifetime methods
(`__enter__`/`__exit__`). We can still set "main" as the current logcontext by using
`PreserveLoggingContext` and passing in the "main" logcontext.


```python
async def main():
main_context = LoggingContext("main")
with PreserveLoggingContext(main_context):
d = defer.Deferred()
d.addCallback(lambda _: defer.ensureDeferred(competing_callback()))
# The whole lambda will be run in the "main" logcontext. But we're using
# a trick to return the deferred `d` itself so that `run_in_background`
# will wait on that to complete and reset the logcontext to the sentinel
# when it does to avoid leaking the "main" logcontext into the reactor.
run_in_background(lambda: (d.callback(None), d)[1])
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This PreserveLoggingContext(LoggingContext("foo")): run_inbackground(...) trick is the same thing we're using in #18907 to run some reactor callbacks with a logging context

@MadLittleMods MadLittleMods marked this pull request as ready for review September 14, 2025 22:18
@MadLittleMods MadLittleMods requested a review from a team as a code owner September 14, 2025 22:18
@github-actions github-actions bot deployed to PR Documentation Preview September 17, 2025 15:02 Active
MadLittleMods added a commit that referenced this pull request Sep 22, 2025
See #18914
for more docs on how deferreds interact with logcontexts
@github-actions github-actions bot deployed to PR Documentation Preview September 22, 2025 19:56 Active
Copy link
Member

@anoadragon453 anoadragon453 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"Phew". Thank you for spending the time to document all of this.

At some point I wonder if the implementation is too complex if it needs all of this documentation. Still, better that it's complex and documented than simple yet not.

…tion-with-deferred

Conflicts:
	tests/util/test_logcontext.py
@github-actions github-actions bot deployed to PR Documentation Preview September 24, 2025 20:56 Active
@MadLittleMods MadLittleMods merged commit 5266e42 into develop Sep 24, 2025
40 checks passed
@MadLittleMods MadLittleMods deleted the madlittlemods/clarify-log-context-interaction-with-deferred branch September 24, 2025 21:20
@MadLittleMods
Copy link
Contributor Author

MadLittleMods commented Sep 24, 2025

Thanks for the review and jumping on this complex topic @anoadragon453 🐕‍🦺

Michael-Ixo pushed a commit to ixoworld/synapse that referenced this pull request Oct 23, 2025
Deployments that make use of the
[synapse-s3-storage-provider](https://github.com/matrix-org/synapse-s3-storage-provider)
module must upgrade to
[v1.6.0](https://github.com/matrix-org/synapse-s3-storage-provider/releases/tag/v1.6.0).
Using older versions of the module with this release of Synapse will prevent
users from being able to upload or download media.

No significant changes since 1.140.0rc1.

- Add [a new Media Query by ID Admin API](https://element-hq.github.io/synapse/v1.140/admin_api/media_admin_api.html#query-a-piece-of-media-by-id) that allows server admins to query and investigate the metadata of local or cached remote media via
  the `origin/media_id` identifier found in a [Matrix Content URI](https://spec.matrix.org/v1.14/client-server-api/#matrix-content-mxc-uris). ([\element-hq#18911](element-hq#18911))
- Add [a new Fetch Event Admin API](https://element-hq.github.io/synapse/v1.140/admin_api/fetch_event.html) to fetch an event by ID. ([\element-hq#18963](element-hq#18963))
- Update [MSC4284: Policy Servers](matrix-org/matrix-spec-proposals#4284) implementation to support signatures when available. ([\element-hq#18934](element-hq#18934))
- Add experimental implementation of the `GET /_matrix/client/v1/rtc/transports` endpoint for the latest draft of [MSC4143: MatrixRTC](matrix-org/matrix-spec-proposals#4143). ([\element-hq#18967](element-hq#18967))
- Expose a `defer_to_threadpool` function in the Synapse Module API that allows modules to run a function on a separate thread in a custom threadpool. ([\element-hq#19032](element-hq#19032))

- Fix room upgrade `room_config` argument and documentation for `user_may_create_room` spam-checker callback. ([\element-hq#18721](element-hq#18721))
- Compute a user's last seen timestamp from their devices' last seen timestamps instead of IPs, because the latter are automatically cleared according to `user_ips_max_age`. ([\element-hq#18948](element-hq#18948))
- Fix bug where ephemeral events were not filtered by room ID. Contributed by @frastefanini. ([\element-hq#19002](element-hq#19002))
- Update Synapse main process version string to include git info. ([\element-hq#19011](element-hq#19011))

- Explain how `Deferred` callbacks interact with logcontexts. ([\element-hq#18914](element-hq#18914))
- Fix documentation for `rc_room_creation` and `rc_reports` to clarify that a `per_user` rate limit is not supported. ([\element-hq#18998](element-hq#18998))

- Remove deprecated `LoggingContext.set_current_context`/`LoggingContext.current_context` methods which already have equivalent bare methods in `synapse.logging.context`. ([\element-hq#18989](element-hq#18989))
- Drop support for unstable field names from the long-accepted [MSC2732](matrix-org/matrix-spec-proposals#2732) (Olm fallback keys) proposal. ([\element-hq#18996](element-hq#18996))

- Cleanly shutdown `SynapseHomeServer` object, allowing artifacts of embedded small hosts to be properly garbage collected. ([\element-hq#18828](element-hq#18828))
- Update OEmbed providers to use 'X' instead of 'Twitter' in URL previews, following a rebrand. Contributed by @HammyHavoc. ([\element-hq#18767](element-hq#18767))
- Fix `server_name` in logging context for multiple Synapse instances in one process. ([\element-hq#18868](element-hq#18868))
- Wrap the Rust HTTP client with `make_deferred_yieldable` so it follows Synapse logcontext rules. ([\element-hq#18903](element-hq#18903))
- Fix the GitHub Actions workflow that moves issues labeled "X-Needs-Info" to the "Needs info" column on the team's internal triage board. ([\element-hq#18913](element-hq#18913))
- Disconnect background process work from request trace. ([\element-hq#18932](element-hq#18932))
- Reduce overall number of calls to `_get_e2e_cross_signing_signatures_for_devices` by increasing the batch size of devices the query is called with, reducing DB load. ([\element-hq#18939](element-hq#18939))
- Update error code used when an appservice tries to masquerade as an unknown device using [MSC4326](matrix-org/matrix-spec-proposals#4326). Contributed by @tulir @ Beeper. ([\element-hq#18947](element-hq#18947))
- Fix `no active span when trying to log` tracing error on startup (when OpenTracing is enabled). ([\element-hq#18959](element-hq#18959))
- Fix `run_coroutine_in_background(...)` incorrectly handling logcontext. ([\element-hq#18964](element-hq#18964))
- Add debug logs wherever we change current logcontext. ([\element-hq#18966](element-hq#18966))
- Update dockerfile metadata to fix broken link; point to documentation website. ([\element-hq#18971](element-hq#18971))
- Note that the code is additionally licensed under the [Element Commercial license](https://github.com/element-hq/synapse/blob/develop/LICENSE-COMMERCIAL) in SPDX expression field configs. ([\element-hq#18973](element-hq#18973))
- Fix logcontext handling in `timeout_deferred` tests. ([\element-hq#18974](element-hq#18974))
- Remove internal `ReplicationUploadKeysForUserRestServlet` as a follow-up to the work in element-hq#18581 that moved device changes off the main process. ([\element-hq#18988](element-hq#18988))
- Switch task scheduler from raw logcontext manipulation to using the dedicated logcontext utils. ([\element-hq#18990](element-hq#18990))
- Remove `MockClock()` in tests. ([\element-hq#18992](element-hq#18992))
- Switch back to our own custom `LogContextScopeManager` instead of OpenTracing's `ContextVarsScopeManager` which was causing problems when using the experimental `SYNAPSE_ASYNC_IO_REACTOR` option with tracing enabled. ([\element-hq#19007](element-hq#19007))
- Remove `version_string` argument from `HomeServer` since it's always the same. ([\element-hq#19012](element-hq#19012))
- Remove duplicate call to `hs.start_background_tasks()` introduced from a bad merge. ([\element-hq#19013](element-hq#19013))
- Split homeserver creation (`create_homeserver`) and setup (`setup`). ([\element-hq#19015](element-hq#19015))
- Swap near-end-of-life `macos-13` GitHub Actions runner for the `macos-15-intel` variant. ([\element-hq#19025](element-hq#19025))
- Introduce `RootConfig.validate_config()` which can be subclassed in `HomeServerConfig` to do cross-config class validation. ([\element-hq#19027](element-hq#19027))
- Allow any command of the `release.py` script to accept a `--gh-token` argument. ([\element-hq#19035](element-hq#19035))

* Bump Swatinem/rust-cache from 2.8.0 to 2.8.1. ([\element-hq#18949](element-hq#18949))
* Bump actions/cache from 4.2.4 to 4.3.0. ([\element-hq#18983](element-hq#18983))
* Bump anyhow from 1.0.99 to 1.0.100. ([\element-hq#18950](element-hq#18950))
* Bump authlib from 1.6.3 to 1.6.4. ([\element-hq#18957](element-hq#18957))
* Bump authlib from 1.6.4 to 1.6.5. ([\element-hq#19019](element-hq#19019))
* Bump bcrypt from 4.3.0 to 5.0.0. ([\element-hq#18984](element-hq#18984))
* Bump docker/login-action from 3.5.0 to 3.6.0. ([\element-hq#18978](element-hq#18978))
* Bump lxml from 6.0.0 to 6.0.2. ([\element-hq#18979](element-hq#18979))
* Bump phonenumbers from 9.0.13 to 9.0.14. ([\element-hq#18954](element-hq#18954))
* Bump phonenumbers from 9.0.14 to 9.0.15. ([\element-hq#18991](element-hq#18991))
* Bump prometheus-client from 0.22.1 to 0.23.1. ([\element-hq#19016](element-hq#19016))
* Bump pydantic from 2.11.9 to 2.11.10. ([\element-hq#19017](element-hq#19017))
* Bump pygithub from 2.7.0 to 2.8.1. ([\element-hq#18952](element-hq#18952))
* Bump regex from 1.11.2 to 1.11.3. ([\element-hq#18981](element-hq#18981))
* Bump serde from 1.0.224 to 1.0.226. ([\element-hq#18953](element-hq#18953))
* Bump serde from 1.0.226 to 1.0.228. ([\element-hq#18982](element-hq#18982))
* Bump setuptools-rust from 1.11.1 to 1.12.0. ([\element-hq#18980](element-hq#18980))
* Bump twine from 6.1.0 to 6.2.0. ([\element-hq#18985](element-hq#18985))
* Bump types-pyyaml from 6.0.12.20250809 to 6.0.12.20250915. ([\element-hq#19018](element-hq#19018))
* Bump types-requests from 2.32.4.20250809 to 2.32.4.20250913. ([\element-hq#18951](element-hq#18951))
* Bump typing-extensions from 4.14.1 to 4.15.0. ([\element-hq#18956](element-hq#18956))
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants